MySQL JDBC StreamResult 和 net_write_timeout
MySQL JDBC 拉取数据的三种方式
MySQL JDBC 在从 MySQL 拉取数据的时候有三种方式:
- 简单模式,也就是默认模式,数据都先要从MySQL Server发到client的OS TCP buffer,然后JDBC把 OS buffer读取到JVM内存中,读取到JVM内存的过程中憋着不让client读取,全部读完再通知inputStream.read(). 数据大的话容易导致JVM OOM
- useCursorFetch=true,配合FetchSize,也就是MySQL Server把查到的数据先缓存到本地磁盘,然后按照FetchSize挨个发给client。这需要占用MySQL很高的IOPS(先写磁盘缓存),其次每次Fetch需要一个RTT,效率不高。
- Stream读取,Stream读取是在执行SQL前设置FetchSize:statement.setFetchSize(Integer.MIN_VALUE),同时确保游标是只读、向前滚动的(为游标的默认值),MySQL JDBC内置的操作方法是将Statement强制转换为:com.mysql.jdbc.StatementImpl,调用其方法:enableStreamingResults(),这2者达到的效果是一致的,都是启动Stream流方式读取数据。这个时候MySQL不停地发数据,inputStream.read()不停地读取。一般来说发数据更快些,很快client的OS TCP recv buffer就满了,这时MySQL停下来等buffer有空闲就继续发数据。等待过程中如果超过 net_write_timeout MySQL就会报错,中断这次查询。
从这里的描述来看,数据小的时候第一种方式还能接受,但是数据大了容易OOM,方式三看起来不错,但是要特别注意 net_write_timeout。
1和3对MySQL Server来说处理上没有啥区别,也感知不到这两种方式的不同。只是对1来说从OS Buffer中的数据复制到JVM内存中速度快,JVM攒多了数据内存就容易爆掉;对3来说JDBC一条条将OS Buffer中的数据复制到JVM(内存复制速度快)同时返回给execute挨个处理(慢),一般来说挨个处理要慢一些,这就导致了从OS Buffer中复制数据较慢,容易导致 TCP Receive Buffer满了,那么MySQL Server感知到的就是TCP 传输窗口为0了,导致暂停传输数据。
在数据量很小的时候方式三没什么优势,因为总是多一次set net_write_tiemout,也就是多了一次RTT。
MySQL timeout
- Creates a statement by calling
Connection.createStatement()
. - Calls
Statement.executeQuery()
. - The statement transmits the Query to MySqlServer by using the internal connection.
- The statement creates a new timeout-execution thread for timeout process.
- For version 5.1.x, it changes to assign 1 thread for each connection.
- Registers the timeout execution to the thread.
- Timeout occurs.
- The timeout-execution thread creates a connection that has the same configurations as the statement.
- Transmits the cancel Query (KILL QUERY “connectionId“) by using the connection.
net_read_timeout
Command-Line Format | --net-read-timeout=# |
---|---|
System Variable | net_read_timeout |
Scope | Global, Session |
Dynamic | Yes |
Type | Integer |
Default Value | 30 |
Minimum Value | 1 |
Maximum Value | 31536000 |
Unit | seconds |
The number of seconds to wait for more data from a connection before aborting the read. When the server is reading from the client, net_read_timeout
is the timeout value controlling when to abort.
如下图,MySQL Server监听3017端口,195228号包 客户端发一个SQL 给 MySQL Server,但是似乎这个时候正好网络异常,30秒钟后(从 SQL 请求的前一个 ack 开始算,Server应该一直都没有收到),Server 端触发 net_read_timeout 超时异常(疑问:这里没有 net_read_timeout 描述的读取了一半的现象)
解决方案:建议调大 net_read_timeout 以应对可能出现的网络丢包
net_write_timeout
show processlist 看到的State的值一直处于“Sending to client”,说明SQL这个语句已经执行完毕,而此时由于请求的数据太多,MySQL不停写入net buffer,而net buffer又不停的将数据写入服务端的网络棧,服务器端的网络栈(socket send buffer)被写满了,又没有被客户端读取并消化,这时读数据的流程就被MySQL暂停了。直到客户端完全读取了服务端网络棧的数据,这个状态才会消失。
先看下 net_write_timeout
的解释:The number of seconds to wait for a block to be written to a connection before aborting the write. 只针对执行查询中的等待超时,网络不好,tcp buffer满了(应用迟迟不读走数据)等容易导致mysql server端报net_write_timeout错误,指的是mysql server hang在那里长时间无法发送查询结果。
Property | Value |
---|---|
Command-Line Format | --net-write-timeout=# |
System Variable | net_write_timeout |
Scope | Global, Session |
Dynamic | Yes |
Type | Integer |
Default Value | 60 |
Minimum Value | 1 |
报这个错就是RDS等了net_write_timeout这么久没写数据,可能是客户端卡死没有读走数据,也可能是从多个分片挨个拉取,还没开始拉第7片前面6片拉取耗时就超过了net_write_timeout。
案例:DRDS 到 MySQL 多个分片拉取数据生成了许多 cursor 并发执行,但拉数据的时候是串行拉取的,如果用户端拉取数据过慢会导致最后一个 cursor 执行完成之后要等待很久.会超过 MySQL 的 net_write_timeout 配置从而引发报错. 也就是最后一个cursor打开后一直没有去读取数据,直到MySQL Server 触发 net_write_timeout 异常
首先可以尝试在 DRDS jdbcurl 配置 netTimeoutForStreamingResults 参数,设置为 0 可以使其一直等待,或设置一个合理的值(秒).
从JDBC驱动中可以看到,当调用PreparedStatement的executeQuery() 方法的时候,如果我们是去获取流式resultset的话,就会默认执行SET net_write_timeout= ? 这个命令去重新设置timeout时间。源代码如下:
1 | if (doStreaming && this.connection.getNetTimeoutForStreamingResults() > 0) { |
而 this.connection.getNetTimeoutForStreamingResults() 默认是600秒,或者在JDBC连接串种通过属性 netTimeoutForStreamingResults 来指定。
netTimeoutForStreamingResults 默认值:
What value should the driver automatically set the server setting ‘net_write_timeout’ to when the streaming result sets feature is in use? Value has unit of seconds, the value “0” means the driver will not try and adjust this value.
Default Value | 600 |
---|---|
Since Version | 5.1.0 |
一般在数据导出场景中容易出现 net_write_timeout 这个错误,比如这个错误堆栈:
或者:
1 | ErrorMessage: |
特别注意
JDBC驱动报如下错误
Application was streaming results when the connection failed. Consider raising value of ‘net_write_timeout’ on the server. - com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Application was streaming results when the connection failed. Consider raising value of ‘net_write_timeout’ on the server.
不一定是 net_write_timeout
设置过小导致的,JDBC 在 streaming 流模式下只要连接异常就会报如上错误,比如:
- 连接被 TCP reset
- 连接因为某种原因(比如 QueryTimeOut、比如用户监控kill 慢查询) 触发 kill Query导致连接中断
比如出现内核bug,内核卡死不发包的话,客户端同样报 net_write_timeout 错误
max_allowed_packet
: 单个SQL或者单条记录的最大大小
一些其他的 Timeout
connectTimeout:表示等待和MySQL数据库建立socket链接的超时时间,默认值0,表示不设置超时,单位毫秒,建议30000。 JDBC驱动连接属性
queryTimeout:超时后jdbc驱动触发新建一个连接来发送一个 kill 给DB
socketTimeout:JDBC参数,表示客户端发送请求给MySQL数据库后block在read的等待数据的超时时间,linux系统默认的socketTimeout为30分钟,可以不设置。socketTimeout 超时不会触发发kill,只会断开tcp连接。
要特别注意socketTimeout仅仅是指等待socket数据时间,如果在传输数据那么这个值就没有用了。socketTimeout通过mysql-connector中的NativeProtocol最终设置在socketOptions上
static final int SO_TIMEOUT。 Set a timeout on blocking Socket operations:
ServerSocket.accept();
SocketInputStream.read();
DatagramSocket.receive();The option must be set prior to entering a blocking operation to take effect. If the timeout expires and the operation would continue to block, java.io.InterruptedIOException is raised. The Socket is not closed in this case.
Statement Timeout:用来限制statement的执行时长,timeout的值通过调用JDBC的java.sql.Statement.setQueryTimeout(int timeout) API进行设置。不过现在开发者已经很少直接在代码中设置,而多是通过框架来进行设置。
max_execution_time
:The execution timeout for SELECT
statements, in milliseconds. If the value is 0, timeouts are not enabled. MySQL 属性,可以set修改,一般用来设置一个查询最长不超过多少秒,避免一个慢查询一直在跑,跟statement timeout对应。
Property | Value |
---|---|
Command-Line Format | --max-execution-time=# |
System Variable | max_execution_time |
Scope | Global, Session |
Dynamic | Yes |
Type | Integer |
Default Value | 0 |
wait_timeout
The number of seconds the server waits for activity on a noninteractive connection before closing it. MySQL 属性,一般设置tcp keepalive后这个值基本不会超时(这句话存疑 202110)。
On thread startup, the session wait_timeout
value is initialized from the global wait_timeout
value or from the global interactive_timeout
value, depending on the type of client (as defined by the CLIENT_INTERACTIVE
connect option to mysql_real_connect()
). See also interactive_timeout
.
Property | Value |
---|---|
Command-Line Format | --wait-timeout=# |
System Variable | wait_timeout |
Scope | Global, Session |
Dynamic | Yes |
Type | Integer |
Default Value | 28800 |
Minimum Value | 1 |
Maximum Value (Other) | 31536000 |
Maximum Value (Windows) | 2147483 |
一般来说应该设置: max_execution_time/statement timeout < Tranction Timeout < socketTimeout
SocketTimeout
这个 httpclient 的bug 就是在 TCP 连接握手成功(只受ConnectTimeout影响,SocketTimeout还不起作用)后,还需要进行 SSL的数据交换(HandShake),但因为httpclient是在连接建立后(含 SSL HandShake)才设置的 SocketTimeout,导致在SSL HandShake的时候卡在了读数据,此时恰好还没设置SocketTimeout,导致连接永久卡死在SSL HandShake的读数据
所以代码的fix方案就是在建连接前就设置好 SocketTimeout。
一次 PreparedStatement 执行
useServerPrepStmts=true&cachePrepStmts=true
5.0.5版本后的驱动 useServerPrepStmts 默认值是false;另外跨Statement是没法重用PreparedStatement预编译的,还需要设置 cachePrepStmts 才可以。
对于打开预编译的URL(String url = “jdbc:mysql://localhost:3306/studb?useServerPrepStmts=true&cachePrepStmts=true”)获取数据库连接之后,本质是获取预编译语句 **pstmt = conn.prepareStatement(sql)**时会向MySQL服务端发送一个RPC,发送一个预编译的SQL模板(驱动会拼接MySQL预编译语句prepare s1 from ‘select * from user where id = ?’),然后MySQL服务端会编译好收到的SQL模板,再会为此预编译模板语句分配一个 serverStatementId发送给JDBC驱动,这样以后PreparedStatement就会持有当前预编译语句的服务端的serverStatementId,并且会把此 PreparedStatement缓存在当前数据库连接中,以后对于相同SQL模板的操作 **pstmt.executeUpdate()**,都用相同的PreparedStatement,执行SQL时只需要发送 serverStatementId 和参数,节省一次SQL编译, 直接执行。并且对于每一个连接(驱动端及MySQL服务端)都有自己的prepare cache,具体的源码实现是在com.mysql.jdbc.ServerPreparedStatement中实现。
根据SQL模板和设置的参数,解析成一条完整的SQL语句,最后根据MySQL协议,序列化成字节流,RPC发送给MySQL服务端
1 | // 解析封装需要发送的SQL语句,序列化成MySQL协议对应的字节流 |
准备好需要发送的MySQL协议的字节流(sendPacket)后,就可以一路通过ConnectionImpl.execSQL –> MysqlIO.sqlQueryDirect –> MysqlIO.send – > OutPutStram.write把字节流数据通过Socket发送给MySQL服务器,然后线程阻塞等待服务端返回结果数据,拿到数据后再根据MySQL协议反序列化成我们熟悉的ResultSet对象。
SocketTimeoutException: Read timed out
如果SQL 超过 SocketTimeout 报错如下:
1 | #java -cp .:./mysql-connector-java-5.1.45.jar Test "jdbc:mysql://127.0.0.1:3306/test?useSSL=false&useServerPrepStmts=true&cachePrepStmts=true&connectTimeout=15000&socketTimeout=3700" root 123 "select sleep(10), id from sbtest1 where id= ?" 100 |
连接超时
在防火墙里设置了 3306 的包都 drop
1 | #java -cp .:./mysql-connector-java-5.1.45.jar Test "jdbc:mysql://127.0.0.1:3306/test?useSSL=false&useServerPrepStmts=true&cachePrepStmts=true&connectTimeout=15000&socketTimeout=3700" root 123 "select sleep(10), id from sbtest1 where id= ?" 100 |
SocketException connection timed out
案例
设置JDBC参数不合理(不设置的话默认值是:queryTimeout=10s,socketTimeout=10s),会导致在异常情况下,第二条get获得了第一条的结果,拿到了错误的数据,数据库则表现正常
socketTimeout触发后,连接抛CommunicationsException(严重异常,触发后连接应该断开), 但JDBC会检查请求是否被cancle了,如果cancle就会抛出MySQLTimeoutException异常,这是一个普通异常,连接会被重新放回连接池重用(导致下一个获取这个连接的线程可能会得到前一个请求的response)。
queryTimeout(queryTimeoutKillsConnection=True–来强制关闭连接)会触发启动一个新的连接向server发送 kill id的命令,MySQL5.7增加了max_statement_time/max_execution_time来做到在server上直接检测到这种查询,然后结束掉。
jdbc 和 RDS之间 socket_timeout
jdbc驱动设置socketTimeout=1459,如果是socketTimeout触发客户端断开后,server端的SQL会继续执行,如果是client被kill则server端的SQL会被终止
1 | # java -cp /home/admin/drds-server/lib/*:. Test "jdbc:mysql://172.16.40.215:3008/bank_000000?socketTimeout=1459" "user" "pass" "select sleep(2)" "1" |
对应抓包,没有 kill动作
CN 和 DN 间socket_timeout案例
设置CN到DN的socket_timeout为2秒,然后执行一个sleep
CN上抓包分析(stream 5是客户端到CN、stream6是CN到DN)如下,首先CN会计时2秒钟后发送quit给DN,然后断开和DN的连接,并返回一个错误给client,client发送quit断开连接:
CN完整报错堆栈:
1 | 2022-06-01 12:10:00.178 [ServerExecutor-bucket-2-19-thread-181] ERROR com.alibaba.druid.pool.DruidPooledStatement - [user=polardbx_root,host=10.101.32.6,port=43947,schema=bank] CommunicationsException, druid version 1.1.24, jdbcUrl : jdbc:mysql://172.16.40.215:3008/bank_000000?maintainTimeStats=false&rewriteBatchedStatements=false&failOverReadOnly=false&cacheResultSetMetadata=true&allowMultiQueries=true&clobberStreamingResults=true&autoReconnect=false&usePsMemOptimize=true&useServerPrepStmts=true&netTimeoutForStreamingResults=0&useSSL=false&metadataCacheSize=256&readOnlyPropagatesToServer=false&prepStmtCacheSqlLimit=4096&connectTimeout=5000&socketTimeout=9000000&cachePrepStmts=true&characterEncoding=utf8&prepStmtCacheSize=256, testWhileIdle true, idle millis 11861, minIdle 5, poolingCount 4, timeBetweenEvictionRunsMillis 60000, lastValidIdleMillis 11861, driver com.mysql.jdbc.Driver, exceptionSorter com.alibaba.polardbx.common.jdbc.sorter.MySQLExceptionSorter |
应用和 DB 间丢包导致 keepalive 心跳失败
应用使用了 Druid 连接池来维护到 DB 间的所有长连接
应用和 DB 间丢包导致 keepalive 心跳失败,进而 OS会断开这个连接
一个连接归还给Druid连接池都要做清理动作,就是第一个红框的rollback/autocommit=1
归还后OS 层面会探活TCP 连接,DB(4381端口)多次后多次不响应keepalive 后,OS 触发reset tcp断开连接,此时上层应用(比如Druid连接池、比如Tomcat)还不知道此连接在OS 层面已经断开
1 | #sysctl -a |grep -i keepalive |
继续过来一个新连接,业务取到这个连接执行查询就会报如下错误:
1 | com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure |
这个错误就是因为OS层面连接断开了,并且断开了162秒(和截图时间戳能对应上)
对应的错误堆栈:
1 | Caused by: java.net.SocketException: Connection timed out (Write failed) |
kill 案例
kill mysql client
mysql client连cn执行一个很慢的SQL,然后kill掉mysql client
cn报错:
1 | 2022-06-01 11:45:59.063 [ServerExecutor-bucket-0-17-thread-158] ERROR com.alibaba.druid.pool.DruidPooledStatement - [user=polardbx_root,host=10.101.32.6,port=50684,schema=bank] CommunicationsException, druid version 1.1.24, jdbcUrl : jdbc:mysql://172.16.40.215:3008/bank_000000?maintainTimeStats=false&rewriteBatchedStatements=false&failOverReadOnly=false&cacheResultSetMetadata=true&allowMultiQueries=true&clobberStreamingResults=true&autoReconnect=false&usePsMemOptimize=true&useServerPrepStmts=true&netTimeoutForStreamingResults=0&useSSL=false&metadataCacheSize=256&readOnlyPropagatesToServer=false&prepStmtCacheSqlLimit=4096&connectTimeout=5000&socketTimeout=9000000&cachePrepStmts=true&characterEncoding=utf8&prepStmtCacheSize=256, testWhileIdle true, idle millis 72028, minIdle 5, poolingCount 4, timeBetweenEvictionRunsMillis 60000, lastValidIdleMillis 345734, driver com.mysql.jdbc.Driver, exceptionSorter com.alibaba.polardbx.common.jdbc.sorter.MySQLExceptionSorter |
mysqld报错:
1 | 2022-06-01T11:45:58.915371+08:00 8218735 [Note] Aborted connection 8218735 to db: 'bank_000000' user: 'rds_polardb_x' host: '172.16.40.214' (Got an error reading communication packets) |
172.16.40.214是客户端IP
抓包看到CN收到mysql client发过来的fin,CN回复fin断开连接
CN会给DN在新的连接上发Kill Query(stream 1596),同时会在原来的连接(stream 583)上发fin,然后原来的连接收到DN的response(被kill),然后CN发reset给DN
下图是sleep 连接的收发包
Kill jdbc client
Java jdbc client被kill后没有错误堆栈,kill后触发socket.close(对应client发送fin断开连接),kill后server端SQL也被立即中断
抓包:
server端报错信息:
1 | 2022-06-01T14:33:52.204848+08:00 8288839 [Note] Aborted connection 8288839 to db: 'bank_000000' user: 'user' host: '172.16.40.214' (Got an error reading communication packets) |
Statement timeout
1 | # java -cp /home/admin/drds-server/lib/*:. Test "jdbc:mysql://172.16.40.215:3008/bank_000000?socketTimeout=5459" "user" "pass" "select sleep(180)" "1" 3 |
statement会设置一个timer,到时间还没有返回结果就创建一个新连接发送kill query
server 端收到kill后终止SQL执行,抓包看到Server端主动提前返回了错误